Hike News
Hike News

使用Arthas trace定位并优化接口响应慢的问题

java 本文总阅读量次

Arthas trace命令介绍

https://alibaba.github.io/arthas/trace.html

打印方法内部调用路径，并输出方法路径上的每个节点上耗时。

trace命令只会trace匹配到的函数里的子调用，并不会向下trace多层。因为trace是代价比较贵的，多层trace可能会导致最终要trace的类和函数非常多。

使用方法

命令格式：

1
trace class method

示例：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
[arthas@30]$ trace com.sunshanpeng.platform.pub.service.impl.PublishServiceImpl checkPrePub
Press Q or Ctrl+C to abort.
Affect(class-cnt:2 , method-cnt:4) cost in 408 ms.
`---ts=2019-11-12 14:47:28;thread_name=http-nio-8266-exec-147;id=7938;is_daemon=true;priority=5;TCCL=org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader@6c902fd5
    `---[3771.437071ms] com.sunshanpeng.platform.pub.service.impl.PublishServiceImpl:checkPrePub()
        +---[0.003039ms] com.sunshanpeng.platform.pub.dto.publish.PublishDetailDTO:getClusterCode() #157
        +---[0.001022ms] java.util.Map:get() #157
        +---[0.002185ms] com.sunshanpeng.platform.pub.common.enums.PubStatusEnum:getCode() #161
        +---[0.001843ms] com.sunshanpeng.platform.pub.dto.publish.PublishDetailDTO:setStatus() #161
        +---[1645.580557ms] com.sunshanpeng.platform.pub.service.impl.PublishServiceImpl:selectBySelective() #162
        +---[0.002757ms] org.springframework.util.CollectionUtils:isEmpty() #163
        +---[0.001587ms] com.sunshanpeng.platform.pub.common.enums.PubStatusEnum:getCode() #169
        +---[0.002123ms] com.sunshanpeng.platform.pub.dto.publish.PublishDetailDTO:setStatus() #169
        +---[1478.93462ms] com.sunshanpeng.platform.pub.service.impl.PublishServiceImpl:selectBySelective() #170
        +---[0.002329ms] org.springframework.util.CollectionUtils:isEmpty() #171
        `---[646.735412ms] com.sunshanpeng.platform.pub.service.impl.PublishServiceImpl:buildPublishDetailDTO() #178
            `---[646.539364ms] com.sunshanpeng.platform.pub.service.impl.PublishServiceImpl:buildPublishDetailDTO()
                +---[0.011378ms] com.sunshanpeng.platform.pub.dto.publish.PublishDetailDTO:getPubEnv() #513
                +---[0.002328ms] org.springframework.util.StringUtils:isEmpty() #513
                +---[0.001789ms] com.sunshanpeng.platform.pub.dto.publish.PublishDetailDTO:getClusterCode() #516
                +---[0.001076ms] org.springframework.util.StringUtils:isEmpty() #516
                +---[0.005232ms] com.sunshanpeng.platform.pub.dto.publish.PublishDetailDTO:getSysCode() #519
                +---[0.001092ms] org.springframework.util.StringUtils:isEmpty() #519
                +---[0.004531ms] com.sunshanpeng.platform.pub.dto.publish.PublishDetailDTO:getSysName() #522
                +---[9.95E-4ms] org.springframework.util.StringUtils:isEmpty() #522
                +---[0.001071ms] com.sunshanpeng.platform.pub.dto.publish.PublishDetailDTO:getPubEnv() #525
                +---[0.001343ms] com.sunshanpeng.platform.pub.dto.publish.PublishDetailDTO:getClusterCode() #525
                +---[0.001108ms] com.sunshanpeng.platform.pub.dto.publish.PublishDetailDTO:getSysCode() #525
                +---[1.617415ms] com.sunshanpeng.platform.pub.service.EnvBindService:getRelationByArgs() #525
                +---[0.002319ms] java.util.List:get() #526
                +---[0.014244ms] java.util.List:size() #527
                +---[0.011744ms] com.sunshanpeng.platform.pub.dto.envbind.EnvBindDetailDTO:getJobName() #527
                +---[0.001469ms] org.springframework.util.StringUtils:isEmpty() #527
                +---[0.001367ms] com.sunshanpeng.platform.pub.dto.envbind.EnvBindDetailDTO:getJobName() #532
                +---[0.006322ms] com.sunshanpeng.platform.pub.dto.publish.PublishDetailDTO:setJobName() #532
                +---[0.001252ms] com.sunshanpeng.platform.pub.dto.publish.PublishDetailDTO:getPubEnv() #535
                +---[0.001285ms] com.sunshanpeng.platform.pub.dto.publish.PublishDetailDTO:getClusterCode() #535
                +---[0.001253ms] com.sunshanpeng.platform.pub.dto.publish.PublishDetailDTO:getSysCode() #535
                +---[643.723767ms] com.sunshanpeng.platform.pub.service.JenkinsService:getBuildArgs() #535
                +---[0.010914ms] com.sunshanpeng.platform.pub.common.enums.CommonStatusEnum:getCode() #536
                +---[0.006734ms] com.sunshanpeng.platform.pub.dto.envbind.EnvBindDetailDTO:getSwEnable() #536
                +---[0.014911ms] java.lang.Integer:equals() #536
                +---[0.002085ms] java.lang.Boolean:valueOf() #536
                +---[0.011168ms] com.sunshanpeng.platform.pub.dto.publish.PublishDetailDTO:setApmEnable() #536
                +---[0.004956ms] com.sunshanpeng.platform.pub.dto.publish.PublishDetailDTO:getPubParamKey() #542
                +---[0.002016ms] org.springframework.util.StringUtils:isEmpty() #542
                +---[0.002196ms] java.util.Map:get() #550
                +---[0.004316ms] com.sunshanpeng.platform.pub.dto.publish.PublishDetailDTO:getPubParamValue() #551
                +---[0.001027ms] org.springframework.util.StringUtils:isEmpty() #551
                +---[0.004536ms] com.sunshanpeng.platform.pub.dto.publish.PublishDetailDTO:getRemark() #559
                +---[0.001113ms] org.springframework.util.StringUtils:isEmpty() #559
                +---[0.004637ms] com.sunshanpeng.platform.pub.dto.publish.PublishDetailDTO:setRemark() #560
                +---[0.001502ms] com.sunshanpeng.platform.pub.dto.publish.PublishDetailDTO:getSysCode() #562
                +---[0.322113ms] com.sunshanpeng.platform.pub.service.impl.PublishServiceImpl:getCiCode() #562
                +---[0.005395ms] com.sunshanpeng.platform.pub.dto.publish.PublishDetailDTO:setCiCode() #562
                +---[0.004249ms] com.sunshanpeng.platform.pub.dto.publish.PublishDetailDTO:setConsoleLog() #563
                +---[0.001335ms] java.lang.Integer:valueOf() #564
                +---[0.004697ms] com.sunshanpeng.platform.pub.dto.publish.PublishDetailDTO:setBuildNo() #564
                +---[0.004276ms] com.sunshanpeng.platform.pub.dto.publish.PublishDetailDTO:setCreator() #565
                +---[0.004354ms] com.sunshanpeng.platform.pub.dto.publish.PublishDetailDTO:setCreatorCode() #566
                +---[0.020689ms] java.time.LocalDateTime:now() #567
                +---[0.004397ms] com.sunshanpeng.platform.pub.dto.publish.PublishDetailDTO:setGmtCreate() #567
                +---[0.002075ms] java.time.LocalDateTime:now() #568
                +---[0.004739ms] com.sunshanpeng.platform.pub.dto.publish.PublishDetailDTO:setGmtModify() #568
                +---[0.001317ms] com.sunshanpeng.platform.pub.common.enums.PubStatusEnum:getCode() #569
                `---[0.001365ms] com.sunshanpeng.platform.pub.dto.publish.PublishDetailDTO:setStatus() #569

可以看到目标方法的耗时为3771.437071ms，其中com.sunshanpeng.platform.pub.service.impl.PublishServiceImpl:selectBySelective()方法调用了两次，并且耗时都在1.5秒左右。

优化前执行计划

1
2
3
4
5
6
7
8
9
mysql> explain select id, ci_code, build_no, creator_code, sys_code, sys_name, pub_env,cluster_code, job_name, pub_param_key, pub_param_value, status, remark,  creator, gmt_create, gmt_modify
from t_pub_publish 
where sys_code = "aim" and pub_env = "qa" and cluster_code = 'cn-hd-idc-test-1' and status = 1;
+----+-------------+---------------+------+---------------+------+---------+------+-------+-------------+
| id | select_type | table         | type | possible_keys | key  | key_len | ref  | rows  | Extra       |
+----+-------------+---------------+------+---------------+------+---------+------+-------+-------------+
|  1 | SIMPLE      | t_pub_publish | ALL  | NULL          | NULL | NULL    | NULL | 30544 | Using where |
+----+-------------+---------------+------+---------------+------+---------+------+-------+-------------+
1 row in set

加组合索引

1
2
ALTER TABLE `t_pub_publish`
ADD INDEX `idx_code` (`sys_code`, `pub_env`, `cluster_code`, `status`) ;

优化后执行计划

1
2
3
4
5
6
7
8
9
mysql> explain select id, ci_code, build_no, creator_code, sys_code, sys_name, pub_env,cluster_code, job_name, pub_param_key, pub_param_value, status, remark,  creator, gmt_create, gmt_modify
from t_pub_publish 
where sys_code = "aim" and pub_env = "qa" and cluster_code = 'cn-hd-idc-test-1' and status = 1;
+----+-------------+---------------+------+---------------+----------+---------+-------------------------+------+-----------------------+
| id | select_type | table         | type | possible_keys | key      | key_len | ref                     | rows | Extra                 |
+----+-------------+---------------+------+---------------+----------+---------+-------------------------+------+-----------------------+
|  1 | SIMPLE      | t_pub_publish | ref  | idx_code      | idx_code | 249     | const,const,const,const |    1 | Using index condition |
+----+-------------+---------------+------+---------------+----------+---------+-------------------------+------+-----------------------+
1 row in set

优化后耗时

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
[arthas@30]$ trace com.sunshanpeng.platform.pub.service.impl.PublishServiceImpl checkPrePub 
Press Q or Ctrl+C to abort.
Affect(class-cnt:2 , method-cnt:1) cost in 390 ms.
`---ts=2019-11-13 13:42:15;thread_name=http-nio-8266-exec-143;id=7934;is_daemon=true;priority=5;TCCL=org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader@6c902fd5
    `---[203.648108ms] com.sunshanpeng.platform.pub.service.impl.PublishServiceImpl:checkPrePub()
        +---[min=4.7E-4ms,max=0.010168ms,total=0.010638ms,count=2] java.lang.Integer:<init>() #157
        +---[4.61E-4ms] java.lang.reflect.Method:invoke() #157
        +---[0.003624ms] com.sunshanpeng.platform.pub.dto.publish.PublishDetailDTO:getClusterCode() #157
        +---[0.001096ms] java.util.Map:get() #157
        +---[0.002196ms] com.sunshanpeng.platform.pub.common.enums.PubStatusEnum:getCode() #161
        +---[0.001674ms] com.sunshanpeng.platform.pub.dto.publish.PublishDetailDTO:setStatus() #161
        +---[0.578989ms] com.sunshanpeng.platform.pub.service.impl.PublishServiceImpl:selectBySelective() #162
        +---[6.84E-4ms] org.springframework.util.CollectionUtils:isEmpty() #163
        +---[5.82E-4ms] com.sunshanpeng.platform.pub.common.enums.PubStatusEnum:getCode() #169
        +---[5.45E-4ms] com.sunshanpeng.platform.pub.dto.publish.PublishDetailDTO:setStatus() #169
        +---[0.407368ms] com.sunshanpeng.platform.pub.service.impl.PublishServiceImpl:selectBySelective() #170
        +---[5.59E-4ms] org.springframework.util.CollectionUtils:isEmpty() #171
        `---[202.38997ms] com.sunshanpeng.platform.pub.service.impl.PublishServiceImpl:buildPublishDetailDTO() #178

优化后SQL查询时间降到1ms不到，总耗时200ms，效果明显。

java